#!/usr/bin/python3
#coding: utf-8
import sys
import re
import time
import os

VERSION_INFO = "runlog_stat v2.0.2.20230310"

TYP_SCHED = 0
TYP_IRQ = 1
TYP_SIRQ = 2
TYP_FUNC = 3

class TraceInfo():
	def __init__(self, typ, name, no):
		self.name = name
		self.no = no
		self.type = typ
		self.total_time = 0
		self.max_time = 0
		self.pts = 0
		self.count = 0

	def addruntime(self, pts, action):
		if action:
			self.pts = pts
		elif self.pts:
			t = pts - self.pts
			self.total_time = self.total_time + t
			self.count = self.count + 1
			if t > self.max_time:
				self.max_time = t

TRACEINFO = [{},{},{},{}]
def add_trace_info(typ, name, no, pts, action, cpu=0):
	info = TRACEINFO[typ]
	if type(no) == int:
		no_idx = no + (cpu << 32)
	else:
		no_idx = no

	if not no_idx in info:
		info[no_idx] = TraceInfo(typ, name, no)
	i = info[no_idx]
	i.addruntime(pts, action)
	i.name = name

def trace_info_exist(typ, no):
	return no in TRACEINFO[typ]

class VCD_TRACE_INFO():
	"""docstring for VCD_TRACE_INFO"""
	def __init__(self, scale_us):
		self.trace_log = []
		self.scale = scale_us #time scale
		self.signals = {}
		self.last_log=""
		self.last_log_val=0

	def calc_signal_wire(self, val):
		if val < 2:
			return 1
		elif val < 256:
			return 8
		elif val < 65536:
			return 16
		else:
			return 32

	def add_signal(self, name, val):
		name = name.replace(' ', '_')
		if not name in self.signals.keys():
			self.signals[name] = 1	# 1 wire
		self.signals[name] = max(val&0xffffffff, self.signals[name])
		return name

	def add_trace_log(self, pts, name, val):
		# 同一时间同一个信号先1再0，gtkwave软件无法显示，这里强制把pts+1，避免此情况
		if self.last_log == name+str(pts) and val != self.last_log_val and val == 0:
			# print(self.last_log, self.last_log_val, name, pts, val)
			pts = pts+1
		name = self.add_signal(name, val)
		self.trace_log.append([pts, val, name])
		self.last_log=name+str(pts)
		self.last_log_val=val

	def add_signal_val(self, name, pts, val):
		self.add_trace_log(pts, name, val)

	def add_start_signal(self, name, pts):
		self.add_trace_log(pts, name, 1)

	def add_end_signal(self, name, pts):
		self.add_trace_log(pts, name, 0)

	def add_pulse_signal(self, name, pts):
		self.add_start_signal(name, pts)
		self.add_end_signal(name, pts+1)

	def print_signals(self):
		print(self.signals)

	def export_to_vcd_file(self, fname):
		print('export to %s...' % fname, end='')
		# sort by pts to avoid gtkwave load err
		# self.trace_log = sorted(self.trace_log)
		with open(fname, 'w+') as f:
			f.write('$version %s $end\n' % VERSION_INFO)
			f.write('$date %s $end\n' % time.asctime())
			f.write('$timescale %d us $end\n' % self.scale)
			f.write('$scope module top $end\n')
			for sig, maxval in self.signals.items():
				ss = re.sub(r'[\.: ]', '_', sig) # charactor '.' and ':' is not allowed
				wire = self.calc_signal_wire(maxval)
				f.write('$var wire {0} {1} {2} $end\n'.format(wire, sig, ss))
			f.write('$upscope $end\n$enddefinitions $end\n')
			for log in self.trace_log:
				if self.signals[log[2]] < 2:
					f.write('#{} {}{}\n'.format(*log))
				else:
					f.write('#{} b{:b} {}\n'.format(*log))
			f.write('\n')
		print('done')

VCD_TRACE = VCD_TRACE_INFO(1)

def blacklist(proc):
	return False
	if proc in ('top', 'regrw'):
		return True

in_sirq = False
in_irq = False

def rename_per_cpu(name, cpu):
	if cpu == 0:
		return name
	else:
		return name + str(cpu)

def parse_usr_log(cpu, pts, desc, action):
	"""
		usr trace format:
		>		func in
		<		func out
		@		func at
		SIRQ:	sirq func
	"""
	act_dict = {'>':1, '<':0, '@':-1}
	if desc[0] in act_dict.keys():
		action = act_dict[desc[0]]
		desc = desc[1:]
		if action != -1:
			VCD_TRACE.add_signal_val(desc, pts, action)
			add_trace_info(TYP_FUNC, desc, desc, pts, action)
		else:
			add_trace_info(TYP_FUNC, desc, desc, pts, 1)
			add_trace_info(TYP_FUNC, desc, desc, pts+1, 0)
			VCD_TRACE.add_pulse_signal(desc, pts)
	elif desc.startswith('SIRQ:'):
		VCD_TRACE.add_signal_val(desc, pts, action)
		add_trace_info(TYP_SIRQ, desc, desc, pts, action)
	else:
		VCD_TRACE.add_signal_val(desc, pts, action)

PROCLIST = {}
def update_process_name(pid, comm):
	if not pid in PROCLIST.keys():
		PROCLIST[pid] = comm
	else:
		comm_old = PROCLIST[pid]
		if comm_old != comm and not comm_old.endswith('>' + comm):
			PROCLIST[pid] = comm_old + '>' + comm
	return PROCLIST[pid]

def parse_sched_log(cpu, pts, last_pid, pid, comm):
	VCD_TRACE.add_signal_val('CPU'+str(cpu), pts, pid)
	if pid == 0:
		pid = -cpu
	if last_pid == 0:
		last_pid  = -cpu
	comm = update_process_name(pid, comm)
	VCD_TRACE.add_start_signal(comm+'@'+str(pid), pts)
	add_trace_info(TYP_SCHED, comm, pid, pts, 1)
	if last_pid in PROCLIST.keys():
		VCD_TRACE.add_end_signal(PROCLIST[last_pid]+'@'+str(last_pid), pts)
		add_trace_info(TYP_SCHED, PROCLIST[last_pid], last_pid, pts, 0)

def parse_irq_log(cpu, pts, irqname, irqno, action):
	irqname = rename_per_cpu(irqname, cpu)
	signal = 'IRQ{}_{}'.format(irqno, irqname)
	VCD_TRACE.add_signal_val(signal, pts, action)
	add_trace_info(TYP_IRQ, irqname, irqno, pts, action, cpu)

IRQSUM = TraceInfo(TYP_IRQ, 'IRQ', 0)
SIRQSUM = TraceInfo(TYP_SIRQ, 'SIRQ', 0)
def parse_func_log(cpu, pts, func, line, action):
	is_irq  = False
	is_sirq = False
	if func == 'handle_irq_event':
		is_irq = True
		in_irq = action
	elif func == 'irq_enter':
		is_irq = True
		in_irq = 1
	elif func == 'irq_exit':
		is_irq = True
		in_irq = 0
	elif func == '__do_softirq':
		is_sirq = True
		in_sirq = action
	else:
		func = rename_per_cpu(func, cpu)
		if line == -1:
			VCD_TRACE.add_signal_val('SIRQ:'+func, pts, action)
			add_trace_info(TYP_SIRQ, func, func, pts, action)
		else:
			VCD_TRACE.add_signal_val(func, pts, action)
			add_trace_info(TYP_FUNC, func, func, pts, action)
		return
	if is_irq:
		name = rename_per_cpu('IRQ', cpu)
		VCD_TRACE.add_signal_val(name, pts, in_irq)
		IRQSUM.addruntime(pts, in_irq)
	elif is_sirq:
		name = rename_per_cpu('SIRQ', cpu)
		VCD_TRACE.add_signal_val(name, pts, in_sirq)
		SIRQSUM.addruntime(pts, in_sirq)


def parse_log(typ, cpu, pts, rl):
	try:
		if typ == 'S':
			parse_sched_log(cpu, pts, int(rl[0]), int(rl[1]), rl[2])
		elif typ == 'I':
			parse_irq_log(cpu, pts, rl[0], int(rl[1]), int(rl[2], 16))
		elif typ == 'F':
			parse_func_log(cpu, pts, rl[0], int(rl[1]), int(rl[2], 16))
		elif typ == 'U':
			parse_usr_log(cpu, pts, rl[0], int(rl[1], 16))
	except Exception as e:
		print("Error when parse log: [%s|%u|%s]" % (typ, pts, rl))
		raise e

if __name__ == '__main__':
	maxline = 999999
	minline = 0
	fn = ''
	print("********** %s ***********" % VERSION_INFO)
	if len(sys.argv) > 1:
		fn = sys.argv[1]
	if len(sys.argv) > 2:
		minline = int(sys.argv[2])
	if len(sys.argv) > 3:
		maxline = int(sys.argv[3])
	if not fn:
		print("usage: %s [logfile] [minline] [maxline]" % sys.argv[0])
		sys.exit()
	parse_cnt = 0
	line = 0
	with open(fn, 'r', encoding='ISO-8859-1') as f:
		while True:
			l = f.readline()
			line = line + 1
			if line < minline:
				continue
			if not l or line > maxline:
				break
			# detect log start of g_trace_pos
			if '###g_trace_pos' in l:
				parse_cnt = parse_cnt + 1
				if parse_cnt == 1:
					minline = max(line, minline)
					continue
				if parse_cnt == 2:
					maxline = min(line, maxline)
					break

			r = re.search(r'([0-9A-F]+)\|([IFSU])\|(\d)\|(\d+)\|(.+)', l)
			if not r:
				if parse_cnt == 1: # break after all continuous lines parsed
					break
				continue
			typ = r.group(2)
			cpu = int(r.group(3))
			pts = int(r.group(4))
			record = r.group(5).split(',')
			parse_log(typ, cpu, pts, record)

	maxline = min(line, maxline)
	print("parse valid trace log in line %s" %([minline, maxline]))

	VCD_TRACE.export_to_vcd_file(os.path.basename(fn)+"_trace.vcd")

	totaltime = 0
	totalirqtime = 0
	totalsirqtime = 0
	for k,v in TRACEINFO[TYP_SCHED].items():
		totaltime = totaltime + v.total_time
	for k,v in TRACEINFO[TYP_IRQ].items():
		totalirqtime = totalirqtime + v.total_time
	for k,v in TRACEINFO[TYP_SIRQ].items():
		totalsirqtime = totalsirqtime + v.total_time
	if totaltime:
		print('=' * 60)
		print('process runtime info:')
		print('-' * 60)
		print('  pid|process         | sched time  | pct. |max time | count')
		total = 0
		for k,v in sorted(TRACEINFO[TYP_SCHED].items(), key=lambda x:x[1].total_time, reverse=True):
			print("%5d|%-16s| %8.3f ms |%4.1f%% | %7d | %5d" % (v.no, v.name, v.total_time/1000, v.total_time/totaltime*100, v.max_time, v.count))
		print('-' * 60)
		print("total: {} -int: {}".format(totaltime, totaltime-totalirqtime))
	else:
		print('no valid process log found!')

	if totalirqtime:
		print('=' * 60)
		print('irq runtime info:')
		print('-' * 60)
		print('irq |name       | cost time   | pct. | max | count')
		total = 0
		for k,v in sorted(TRACEINFO[TYP_IRQ].items(), key=lambda x:x[1].total_time, reverse=True):
			print("%3d |%-11s| %8.3f ms |%4.1f%% |%4d | %5d" % (v.no, v.name, v.total_time/1000, v.total_time/totalirqtime*100, v.max_time, v.count))
		print('-' * 60)
		print("total: {}	irqtime:{}".format(totalirqtime, IRQSUM.total_time))

	if totalsirqtime:
		print('=' * 60)
		print('sirq runtime info:')
		print('-' * 60)
		print('sirq name             | cost time   | pct. | max  | count')
		total = 0
		for k,v in sorted(TRACEINFO[TYP_SIRQ].items(), key=lambda x:x[1].total_time, reverse=True):
			print("%-22s| %8.3f ms |%4.1f%% |%5d | %5d" % (v.name, v.total_time/1000, v.total_time/totalsirqtime*100, v.max_time, v.count))
		print('-' * 60)
		print("total: {} sirqtime:{}".format(totalsirqtime, SIRQSUM.total_time))


	if TRACEINFO[TYP_FUNC]:
		print('=' * 60)
		print('function runtime info:')
		print('-' * 60)
		print('function                | cost time   | max  | count')
		total = 0
		for k,v in sorted(TRACEINFO[TYP_FUNC].items(), key=lambda x:x[1].total_time, reverse=True):
			print("%-24s| %8.3f ms |%5d | %5d" % (v.name, v.total_time/1000, v.max_time, v.count))

	print('=' * 60)
